Review logging across WebSocket implementation by mathieucarbou · Pull Request #397 · ESP32Async/ESPAsyncWebServer

mathieucarbou · 2026-03-08T20:23:41Z

This PR adds some verbose logging to the WebSocket implementation on top of the existing one (which as been reviewed) in order to help users debug.

Example when using USE_ESP_IDF_LOG:

  -D USE_ESP_IDF_LOG
  -D LOG_LOCAL_LEVEL=ESP_LOG_VERBOSE
  -D CORE_DEBUG_LEVEL=ARDUHAL_LOG_LEVEL_VERBOSE

  esp_log_level_set("*", ESP_LOG_DEBUG);
  esp_log_level_set("esp_core_dump_elf", ESP_LOG_INFO);
  esp_log_level_set("esp_core_dump_port", ESP_LOG_INFO);
  esp_log_level_set("esp_netif_lwip", ESP_LOG_INFO);
  esp_log_level_set("nvs", ESP_LOG_INFO);
  esp_log_level_set("ARDUINO", ESP_LOG_DEBUG);

  // to debug async_tcp + async_ws
  esp_log_level_set("async_tcp", ESP_LOG_VERBOSE);
  esp_log_level_set("async_ws", ESP_LOG_VERBOSE);

Output example

V (25869) async_ws: _queueMessage() 510: [/dashws][1] QUEUE MSG (1/16) << 2
V (25870) async_ws: _runQueue() 410: [/dashws][1][2] SEND 0/313 (acked: 0/0)
V (25882) async_ws: send() 230: SEND[2] => [63930] WS_MSG_SENDING 313/313 (acked: 0/317)
V (25887) async_ws: _onAck() 312: [/dashws][1] START ACK(317, 6) Q:1
V (25887) async_ws: ack() 175: ACK[2] 313/313 (acked: 317/317) => 1
V (25898) async_ws: _onAck() 354: [/dashws][1] END ACK(0, 6) Q:0
V (26157) async_ws: _onData() 582: [/dashws][1] DATA plen: 8, _pstate: 0, _status: 1
V (26159) async_ws: _onData() 611: [/dashws][1] DATA _pinfo: index: 0, final: 1, opcode: 8, masked: 1, len: 2
V (26169) async_ws: _onData() 651: [/dashws][1] DATA mask read complete
V (26179) async_ws: _onData() 693: [/dashws][1] DATA WS_DISCONNECT
V (26180) async_ws: _queueControl() 466: [/dashws][1] QUEUE CTRL (1) << 8
V (26192) async_ws: _onDisconnect() 572: [/dashws][1] DISCONNECT
V (26518) async_ws: _onData() 582: [/dashws][2] DATA plen: 26, _pstate: 0, _status: 1
V (26520) async_ws: _onData() 611: [/dashws][2] DATA _pinfo: index: 0, final: 1, opcode: 2, masked: 1, len: 20
V (26530) async_ws: _onData() 651: [/dashws][2] DATA mask read complete
V (26541) async_ws: _onData() 727: [/dashws][2] DATA processing final fragment of binary frame 0, index: 0, len: 20
I (26552) YASOLR: Dashboard refresh requested!
V (26569) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (1/16) << 2
V (26570) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/509 (acked: 0/0)
V (26582) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 509/509 (acked: 0/513)
V (26590) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (2/16) << 2
V (26591) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/1757 (acked: 0/0)
V (26603) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 1757/1757 (acked: 0/1761)
V (26616) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (3/16) << 2
V (26616) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2107 (acked: 0/0)
V (26628) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2107/2107 (acked: 0/2111)
V (26641) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (4/16) << 2
V (26641) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2099 (acked: 0/0)
V (26653) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2099/2099 (acked: 0/2103)
V (26664) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (5/16) << 2
V (26665) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2094 (acked: 0/0)
V (26676) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2094/2094 (acked: 0/2098)
V (26687) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (6/16) << 2
V (26688) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2102 (acked: 0/0)
V (26699) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2102/2102 (acked: 0/2106)
V (26708) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (7/16) << 2
V (26708) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2114 (acked: 0/0)
V (26720) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2114/2114 (acked: 0/2118)
V (26727) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (8/16) << 2
V (26727) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2626 (acked: 0/0)
V (26739) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2626/2626 (acked: 0/2630)
V (26751) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (9/16) << 2
V (26751) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2133 (acked: 0/0)
V (26764) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2133/2133 (acked: 0/2137)
V (26775) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (10/16) << 2
V (26775) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/2105 (acked: 0/0)
V (26787) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 2105/2105 (acked: 0/2109)
V (26791) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (11/16) << 2
V (26802) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/398 (acked: 0/0)
V (26803) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 398/398 (acked: 0/402)
V (26818) async_ws: _onAck() 312: [/dashws][2] START ACK(513, 16) Q:11
V (26819) async_ws: ack() 175: ACK[2] 509/509 (acked: 513/513) => 1
V (26830) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 16) Q:10
V (26830) async_ws: _onAck() 312: [/dashws][2] START ACK(1761, 27) Q:10
V (26840) async_ws: ack() 175: ACK[2] 1757/1757 (acked: 1761/1761) => 1
V (26841) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 27) Q:9
V (26851) async_ws: _onAck() 312: [/dashws][2] START ACK(1436, 49) Q:9
V (26851) async_ws: ack() 175: ACK[2] 2107/2107 (acked: 1436/2111) => 0
V (26862) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 49) Q:9
V (26862) async_ws: _onAck() 312: [/dashws][2] START ACK(675, 60) Q:9
V (26872) async_ws: ack() 175: ACK[2] 2107/2107 (acked: 2111/2111) => 1
V (26883) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 60) Q:8
V (26883) async_ws: _onAck() 312: [/dashws][2] START ACK(1436, 81) Q:8
V (26891) async_ws: _queueMessage() 510: [/dashws][2] QUEUE MSG (9/16) << 2
V (26894) async_ws: _runQueue() 410: [/dashws][2][2] SEND 0/394 (acked: 0/0)
V (26906) async_ws: send() 230: SEND[2] => [64045] WS_MSG_SENDING 394/394 (acked: 0/398)
V (26917) async_ws: ack() 175: ACK[2] 2099/2099 (acked: 1436/2103) => 0
V (26917) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 81) Q:9
V (26927) async_ws: _onAck() 312: [/dashws][2] START ACK(667, 22) Q:9
V (26928) async_ws: ack() 175: ACK[2] 2099/2099 (acked: 2103/2103) => 1
V (26938) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 22) Q:8
V (26938) async_ws: _onAck() 312: [/dashws][2] START ACK(1436, 33) Q:8
V (26949) async_ws: ack() 175: ACK[2] 2094/2094 (acked: 1436/2098) => 0
V (26949) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 33) Q:8
V (26959) async_ws: _onAck() 312: [/dashws][2] START ACK(662, 54) Q:8
V (26970) async_ws: ack() 175: ACK[2] 2094/2094 (acked: 2098/2098) => 1
V (26970) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 54) Q:7
V (26981) async_ws: _onAck() 312: [/dashws][2] START ACK(2106, 75) Q:7
V (26981) async_ws: ack() 175: ACK[2] 2102/2102 (acked: 2106/2106) => 1
V (26991) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 75) Q:6
V (26991) async_ws: _onAck() 312: [/dashws][2] START ACK(1436, 86) Q:6
V (27002) async_ws: ack() 175: ACK[2] 2114/2114 (acked: 1436/2118) => 0
V (27012) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 86) Q:6
V (27013) async_ws: _onAck() 312: [/dashws][2] START ACK(682, 107) Q:6
V (27023) async_ws: ack() 175: ACK[2] 2114/2114 (acked: 2118/2118) => 1
V (27023) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 107) Q:5
V (27034) async_ws: _onAck() 312: [/dashws][2] START ACK(1436, 128) Q:5
V (27034) async_ws: ack() 175: ACK[2] 2626/2626 (acked: 1436/2630) => 0
V (27044) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 128) Q:5
V (27055) async_ws: _onAck() 312: [/dashws][2] START ACK(1194, 149) Q:5
V (27055) async_ws: ack() 175: ACK[2] 2626/2626 (acked: 2630/2630) => 1
V (27065) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 149) Q:4
V (27066) async_ws: _onAck() 312: [/dashws][2] START ACK(2137, 160) Q:4
V (27076) async_ws: ack() 175: ACK[2] 2133/2133 (acked: 2137/2137) => 1
V (27077) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 160) Q:3
V (27087) async_ws: _onAck() 312: [/dashws][2] START ACK(2109, 182) Q:3
V (27098) async_ws: ack() 175: ACK[2] 2105/2105 (acked: 2109/2109) => 1
V (27098) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 182) Q:2
V (27108) async_ws: _onAck() 312: [/dashws][2] START ACK(402, 203) Q:2
V (27109) async_ws: ack() 175: ACK[2] 398/398 (acked: 402/402) => 1
V (27119) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 203) Q:1
V (27123) async_ws: _onAck() 312: [/dashws][2] START ACK(398, 217) Q:1
V (27133) async_ws: ack() 175: ACK[2] 394/394 (acked: 398/398) => 1
V (27134) async_ws: _onAck() 354: [/dashws][2] END ACK(0, 217) Q:0

Copilot

Pull request overview

This PR standardizes and expands verbose logging across the WebSocket send/ack/data paths to improve traceability (server URL, client ID, opcode, and queue state).

Changes:

Refactors multiple log messages to use a consistent prefix format (e.g., [%s][id], SEND[...], DATA ...).
Adds start/end and state-transition logs for ACK processing and queue operations.
Adds/logs additional lifecycle events (close, error, timeout, disconnect) and a cleanup log.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

mathieucarbou requested review from Copilot, me-no-dev, vortigont and willmmiles March 8, 2026 20:23

mathieucarbou self-assigned this Mar 8, 2026

mathieucarbou added the Status: Pending Merge label Mar 8, 2026

Copilot AI reviewed Mar 8, 2026

View reviewed changes

mathieucarbou force-pushed the logging branch from 91bc019 to e6c6041 Compare March 8, 2026 20:31

Copilot started reviewing on behalf of mathieucarbou March 8, 2026 20:32 View session

mathieucarbou force-pushed the logging branch 4 times, most recently from b164a83 to ea24c63 Compare March 8, 2026 20:53

Review logging across WebSocket implementation

60c590b

mathieucarbou force-pushed the logging branch from 5db0b85 to 60c590b Compare March 8, 2026 20:54

me-no-dev approved these changes Mar 9, 2026

View reviewed changes

mathieucarbou merged commit e939f7e into main Mar 9, 2026
33 checks passed

mathieucarbou deleted the logging branch March 9, 2026 10:50

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Review logging across WebSocket implementation#397

Review logging across WebSocket implementation#397
mathieucarbou merged 1 commit intomainfrom
logging

mathieucarbou commented Mar 8, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

mathieucarbou commented Mar 8, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

mathieucarbou commented Mar 8, 2026 •

edited

Loading